-
Notifications
You must be signed in to change notification settings - Fork 771
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Add logging buffering #5635
base: main
Are you sure you want to change the base?
Add logging buffering #5635
Conversation
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
...Core.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs
Outdated
Show resolved
Hide resolved
test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs
Show resolved
Hide resolved
...s/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs
Outdated
Show resolved
Hide resolved
test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs
Outdated
Show resolved
Hide resolved
e40b7b6
to
9d61d12
Compare
9d61d12
to
2f1a335
Compare
...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
/// Defines a rule used to filter log messages for purposes of futher buffering. | ||
/// </summary> | ||
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] | ||
public class BufferFilterRule : ILoggerFilterRule |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think we need to also support filtering per name/value pair. So that you can control buffering based on things like cluster name or region.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Would cluster name and region be key-value pairs that are varying within the same process? Based on the names those sound like properties that would be fixed at process startup and remain constant throughout. This means all the decision making could occur at startup time when defining the filter rules rather than a decision that needs to be made per-log message later on. For example could you satisfy the scenario with some startup code like this?
logging.AddBuffering(buffering =>
{
string region = GetRegionFromConfig();
// in the test region we want to buffer some log messages that won't be buffered
// in other regions
if(region == "TestRegion")
{
buffer.AddFilter("ExperimentalFeatures");
}
...
});
I'm not opposed to other things, I'm just trying to better understand what the scenario is.
...soft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
Address PR comments Add .NET 8 support Add ExceptionJsonConverter
883334d
to
022f00c
Compare
022f00c
to
a371d9c
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=896358&view=codecoverage-tab |
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
{ | ||
case ModernTagJoiner modernTagJoiner: | ||
_buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), modernTagJoiner, exception, | ||
((Func<ModernTagJoiner, Exception?, string>)(object)formatter)(modernTagJoiner, exception))); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is this casting more performant than just formatter(attributes, exception)
?
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs
Outdated
Show resolved
Hide resolved
public void Flush() | ||
{ | ||
var result = _buffer.ToArray(); | ||
|
||
#if NETFRAMEWORK | ||
lock (_netfxBufferLocker) | ||
{ | ||
while (_buffer.TryDequeue(out _)) | ||
{ | ||
// Clear the buffer | ||
} | ||
} | ||
#else | ||
_buffer.Clear(); | ||
#endif |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This loses log entries if another thread enqueues more of them between _buffer.ToArray()
and _buffer.Clear()
. That is more likely to happen on .NET Framework, where clearing the queue takes more time.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Moved the _lastFlushTimestamp
update to the top, so that when a flush operation is initiated at one thread, another thread will skip buffering for some period of time because of the non-zero value of SuspendAfterFlushDuration
option. Don't expect someone to set it to zero because it does not make sense to emit some buffered logs and buffer other at almost the same time.
{ | ||
while (!cancellationToken.IsCancellationRequested) | ||
{ | ||
await _timeProvider.Delay(_options.CurrentValue.Duration, cancellationToken).ConfigureAwait(false); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
IIRC, IOptionsMonitor<TOptions>.CurrentValue throws if the option is bound to configuration and the binding fails (parsing fails or a validator rejects the value); this could even happen when an operator modifies a configuration file after the application has already started. The BackgroundService would then fail and, depending on HostOptions.BackgroundServiceExceptionBehavior, either log buffer truncation would stop working or the whole application would terminate. Should this instead keep using the previous value of the options in that case?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This makes sense, but I will take another look at it later on, possibly after finalizing public API. Keeping this open until then
src/Libraries/Microsoft.Extensions.Telemetry/ILoggerFilterRule.cs
Outdated
Show resolved
Hide resolved
logger.Log( | ||
serializedRecord.LogLevel, | ||
serializedRecord.EventId, | ||
serializedRecord.Attributes, | ||
exception, | ||
(_, _) => serializedRecord.FormattedMessage ?? string.Empty); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This allocates a closure and a delegate for each ILogger.Log<TState> call. I can think of two ways to minimize the allocations:
- Instead of
serializedRecord.Attributes
, passserializedRecord
itself as the state to ILogger.Log<TState>. ImplementIReadOnlyList<KeyValuePair<string, object?>>
in SerializedLogRecord by calling the corresponding methods ofpublic IReadOnlyList<KeyValuePair<string, string>> Attributes
. - Alternatively, keep using the same delegate across all iterations of both
foreach
loops; declare theserializedRecord
variable and a delegate variable before the outer loop. That way, it would allocate only one closure and one delegate per BufferSink.LogRecords call, no matter how many log records are inIEnumerable<T> serializedRecords
. This is safe because ILogger.Log<TState> is not allowed to save the formatter delegate for later calling.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
makes sense for optimizations later, thank you
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This code moved from BufferSink to BufferedLoggerProxy in d7661a6. The BufferedLogRecord instances are not pooled, so each BufferedLogRecord call costs at least one allocation per BufferedLogRecord; that may make the delegate and closure allocations less important.
using Microsoft.Extensions.ObjectPool; | ||
|
||
namespace Microsoft.Extensions.Diagnostics.Buffering; | ||
internal sealed class PooledLogRecord : BufferedLogRecord, IResettable |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please add DebuggerDisplayAttribute so that the list of log records in a buffer can be viewed more easily.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Or add the DebuggerDisplayAttribute to SerializedLogRecord, instead.
e5905b1
to
5fc421c
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=919881&view=codecoverage-tab |
Category = categoryName; | ||
LogLevel = logLevel; | ||
EventId = eventId; | ||
Filter = filter ?? ((_, _, _, _) => true); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It might be more efficient to leave Filter
as null and not call the filter in that case. I expect that most rules won't have a filter specified and the null check will be well predicted by processors. It would also make rules easier to understand in a debugger as actual filters would stand out better.
src/Libraries/Microsoft.Extensions.Telemetry/LoggerFilterRuleSelector.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferFilterRule.cs
Outdated
Show resolved
Hide resolved
public int? EventId { get; set; } | ||
|
||
/// <inheritdoc/> | ||
public Func<string?, LogLevel?, EventId?, IReadOnlyList<KeyValuePair<string, object?>>, bool> Filter { get; } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Are there any callsites where Filter is invoked with a null category string, null log level, or null EventId? If yes thats a little surprising but fine as long as we define what that would mean. If no then those parameter types don't need to be nullable.
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs
Outdated
Show resolved
Hide resolved
{ | ||
await context.Request.Body.DrainAsync(default); | ||
|
||
// normally, this would be a Middleware and IHttpRequestBufferManager would be injected via constructor |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
await next(context).ConfigureAwait(false);
}
This is the spot in the middleware where I would expect the majority of logging would occur. Right now it looks like the example code would not buffer that common case logging.
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
8b8558a
to
e96277f
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=923995&view=codecoverage-tab |
I asked this in one of comments but didn't see answer. Are we going to take these APIs to the design review? |
We are going to take it to API review https://apireview.net. I am not aware of design review, is it different than the API review in .NET? |
No, should be same. You may consult the doc https://github.com/dotnet/runtime/blob/main/docs/project/api-review-process.md for the details. Thanks! |
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925013&view=codecoverage-tab |
8319dc8
to
8a91c15
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925328&view=codecoverage-tab |
|
||
public int GetHashCode(KeyValuePair<string, object?> obj) | ||
{ | ||
return HashCode.Combine(obj.Key, obj.Value); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This would have to be obj.Value?.ToString()
, in order to be consistent with Equals.
Alternatively just throw NotImplementedException, if this is designed to be used only with Enumerable.Contains, which doesn't call GetHashCode anyway.
d387358
to
4f524eb
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925376&view=codecoverage-tab |
namespace Microsoft.Extensions.Diagnostics.Buffering; | ||
|
||
/// <summary> | ||
/// Defines a rule used to filter log messages for purposes of futher buffering. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
"further"
/// <summary> | ||
/// Defines a rule used to filter log messages for purposes of futher buffering. | ||
/// </summary> | ||
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] | ||
public class BufferFilterRule |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This should have docs about what happens if a log entry matches a rule, and what happens if the log entry does not match any rule.
- Is the log entry discarded, buffered, or written directly to underlying loggers?
- Does it cause other log entries to be flushed from the buffer to underlying loggers? If so, does that apply to all log categories or only to the same category?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Alternatively, if this type is used with different semantics in different contexts, then document the behaviour in HttpRequestBufferOptions.Rules and GlobalBufferOptions.Rules, and link to those docs from here.
5201765
to
7afd271
Compare
7afd271
to
b2b6e56
Compare
Related to the #5123 proposal, this PR is focused on the logging buffering only. See also the sampling part #5574.
Microsoft Reviewers: Open in CodeFlow